GlassFish - World's first Java EE 7 Application Server


EJB Timer Service Demo

This demo is shows creating automatic (i.e. defined by @Schedule annotation) EJB timer in a cluster and automatic (i.e. as a result of a GMS notification) timer migration if an instance that owns EJB Timers in a cluster is stopped.

The demo uses ejb devtest 

v2/appserv-tests/devtests/ejb/ee/timer/autotimer
to step through various stages

Team

  • Marina Vatkina

Setup and Cluster creation

Important: if you execute this test on MS4 build, copy _war/MyBean.java.ms4_ to _war/MyBean.java_

  1. Compile the classes and create the WAR file to be deployed:
ant build
  1. Setup:
    1. Start JavaDB database
    2. Start DAS.
    3. Create a resource that can be shared by all instances in the cluster (_jdbc/mypool_)
    4. Register this resource as the _ejb-timer-service.timer-datasource_ with the _default-config_.
    5. Create and start the cluster of 2 instances
ant setup

Deploying the application and starting automatic timer

  1. Deploy the application:
ant deploy
  1. You can notice that the timeouts are delivered only on one (randomly picked) instance out of two that belong to the cluster. Check instance logs _glassfishv3/glassfish/nodes/localhost/in1/logs/server.log_ and _glassfishv3/glassfish/nodes/localhost/in2/logs/server.log_ to see the following output only on one instance:
[#|2010-08-23T17:26:39.640-0700|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.deployment.admin|_ThreadID=15;_ThreadName=Thread-1;|ejb-ee-autotimer-web was successfully deployed in 9,901 milliseconds.|#]

and

[#|2010-08-23T17:26:48.044-0700|INFO|glassfish3.1|javax.enterprise.system.tools.admin.org.glassfish.deployment.admin|_ThreadID=15;_ThreadName=Thread-1;|ejb-ee-autotimer-web was successfully deployed in 8,254 milliseconds.|#]

[#|2010-08-23T17:26:48.950-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer01 - persistent: true|#]

[#|2010-08-23T17:26:50.043-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer01 - persistent: true|#]

[#|2010-08-23T17:26:55.024-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer01 - persistent: true|#]

Stopping automatic timer on MS4 build and creating programmatic timer

  1. On MS4 build, the automatic timer needs to be cancelled (MS4 build does not support ustomatic timer failover, but any MS5 builds do).
  2. Programmatic timer is started on each instance in the cluster:
ant run-test

The corresponding log files will contain (there will be no _MyBean: cancelling timer_ message and 2 timers migrated from _in2_ to _in1_ on MS5 build):

[#|2010-08-23T17:27:43.432-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeoutReceived___ 0 times|#]

[#|2010-08-23T17:27:43.432-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean: cancelling timer01|#]

[#|2010-08-23T17:27:44.573-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28080 - persistent: true|#]

[#|2010-08-23T17:27:49.481-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28080 - persistent: true|#]

and

[#|2010-08-23T17:27:43.925-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean: cancelling timer01|#]

[#|2010-08-23T17:27:45.042-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28081 - persistent: true|#]

[#|2010-08-23T17:27:49.970-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28081 - persistent: true|#]

Stopping one instance

In our test _in2_ was the original instance with the timer:

asadmin stop-instance in2

Will result in these messages in the corresponding logs:

[#|2010-08-23T17:28:34.479-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28080 - persistent: true|#]

[#|2010-08-23T17:28:38.451-0700|INFO|glassfish3.1|ShoalLogger|_ThreadID=15;_ThreadName=Thread-1;|GMS View Change Received for group c1 : Members in view for PEER_STOP_EVENT(before change analysis) are :
1: MemberId: server, MemberType: SPECTATOR, Address: 10.132.180.145:9090:28395:c1:server
2: MemberId: in1, MemberType: CORE, Address: 10.132.180.145:9091:28395:c1:in1
|#]

[#|2010-08-23T17:28:38.451-0700|INFO|glassfish3.1|ShoalLogger|_ThreadID=15;_ThreadName=Thread-1;|Analyzing new membership snapshot received as part of event : PEER_STOP_EVENT for Member: in2 of Group: c1|#]

[#|2010-08-23T17:28:38.464-0700|INFO|glassfish3.1|ShoalLogger|_ThreadID=15;_ThreadName=Thread-1;|Received PlannedShutdownEvent Announcement from Instance in2 with Shutdown type = INSTANCE_SHUTDOWN of Group: c1|#]

[#|2010-08-23T17:28:38.492-0700|INFO|glassfish3.1|ShoalLogger|_ThreadID=15;_ThreadName=Thread-1;|Sending PlannedShutdownSignals to registered Actions for shutdownType INSTANCE_SHUTDOWN Member: in2...|#]

[#|2010-08-23T17:28:38.516-0700|INFO|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=15;_ThreadName=Thread-1;|[DistributedEJBTimerServiceImpl] migrating timers from in2|#]

[#|2010-08-23T17:28:38.516-0700|INFO|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=15;_ThreadName=Thread-1;|Beginning timer migration process from owner in2 to in1|#]

[#|2010-08-23T17:28:38.550-0700|INFO|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=15;_ThreadName=Thread-1;|Timer migration phase 1 complete. Changed ownership of 1 timers.  Now reactivating timers...|#]

[#|2010-08-23T17:28:39.577-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28080 - persistent: true|#]

[#|2010-08-23T17:28:39.971-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28081 - persistent: true|#]

[#|2010-08-23T17:28:44.481-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28080 - persistent: true|#]

[#|2010-08-23T17:28:44.969-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28081 - persistent: true|#]

and 

[#|2010-08-23T17:28:34.970-0700|SEVERE|glassfish3.1|null|_ThreadID=15;_ThreadName=Thread-1;|In ___MyBean:timeout___ timer02 28081 - persistent: true|#]

[#|2010-08-23T17:28:37.300-0700|INFO|glassfish3.1|javax.enterprise.system.tools.admin.com.sun.enterprise.v3.admin.cluster|_ThreadID=15;_ThreadName=Thread-1;|Server shutdown initiated|#]

[#|2010-08-23T17:28:37.322-0700|INFO|glassfish3.1|org.jvnet.hk2.osgiadapter|_ThreadID=15;_ThreadName=Thread-1;|Stopping com.sun.enterprise.v3.server.AppServerStartup@13eaab|#]

[#|2010-08-23T17:28:37.384-0700|INFO|glassfish3.1|javax.enterprise.system.container.ejb.com.sun.ejb.containers|_ThreadID=15;_ThreadName=Thread-1;|[TimerBeanContainer] Shutdown() called....|#]

Cleanup

To undeploy the application, stop and remove the cluster do:

and undeploy unsetup

This is the end of the demo and the test.